**** dT 0.000
* top TEST ../../../../bin/varnishtest/tests/r03996.vtc starting
**** top extmacro def pkg_version=trunk
**** top extmacro def pkg_branch=trunk
**** top extmacro def pwd=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest
**** top extmacro def date(...)
**** top extmacro def string(...)
**** top extmacro def localhost=127.0.0.1
**** top extmacro def bad_backend=127.0.0.1:43211
**** top extmacro def listen_addr=127.0.0.1:0
**** top extmacro def bad_ip=192.0.2.255
**** top extmacro def topbuild=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub
**** top extmacro def topsrc=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/../..
**** top macro def testdir=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest/../../../../bin/varnishtest/tests
**** top macro def tmpdir=/home/linux1/VT/_vtest_tmp/vtc.2092523.29c1aac3
**** top macro def vtcid=vtc.2092523.29c1aac3
** top === varnishtest "h2 rapid reset"
* top VTEST h2 rapid reset
** top === barrier b1 sock 2 -cyclic
**** b1 macro def b1_addr=127.0.0.1
**** b1 macro def b1_port=38283
**** b1 macro def b1_sock=127.0.0.1:38283
** top === barrier b2 sock 5 -cyclic
**** dT 0.001
**** b2 macro def b2_addr=127.0.0.1
**** b2 macro def b2_port=37437
**** b2 macro def b2_sock=127.0.0.1:37437
**** dT 0.004
** top === server s1 {
** s1 Starting server
**** s1 macro def s1_addr=127.0.0.1
**** s1 macro def s1_port=39379
**** s1 macro def s1_sock=127.0.0.1:39379
* s1 Listen on 127.0.0.1:39379
** top === varnish v1 -cliok "param.set feature +http2"
**** dT 0.015
** v1 Launch
*** v1 CMD: cd ${pwd} && exec varnishd -d -n /home/linux1/VT/_vtest_tmp/vtc.2092523.29c1aac3/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 37877' -P /home/linux1/VT/_vtest_tmp/vtc.2092523.29c1aac3/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs
*** v1 CMD: cd /home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /home/linux1/VT/_vtest_tmp/vtc.2092523.29c1aac3/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 37877' -P /home/linux1/VT/_vtest_tmp/vtc.2092523.29c1aac3/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs
*** v1 PID: 2092544
**** v1 macro def v1_pid=2092544
**** v1 macro def v1_name=/home/linux1/VT/_vtest_tmp/vtc.2092523.29c1aac3/v1
**** dT 0.018
*** v1 debug|Info: Working directory not mounted on tmpfs partition
*** v1 debug|
**** dT 0.065
*** v1 debug|Debug: Version: varnish-trunk revision 459a636f137c48328af64677ac426af5f4af7654
*** v1 debug|Debug: Platform: Linux,4.18.0-553.44.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
*** v1 debug|200 329
*** v1 debug|-----------------------------
*** v1 debug|Varnish Cache CLI 1.0
*** v1 debug|-----------------------------
*** v1 debug|Linux,4.18.0-553.44.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
*** v1 debug|varnish-trunk revision 459a636f137c48328af64677ac426af5f4af7654
*** v1 debug|
*** v1 debug|Type 'help' for command list.
*** v1 debug|Type 'quit' to close CLI session.
*** v1 debug|Type 'start' to launch worker process.
*** v1 debug|
**** dT 0.077
** s1 Started on 127.0.0.1:39379 (1 iterations)
**** dT 0.170
**** v1 CLIPOLL 1 0x1 0x0 0x0
*** v1 CLI connection fd = 11
*** v1 CLI RX 107
**** v1 CLI RX|ymwphhlnuwzwskmefafsennlbfocfncn
**** v1 CLI RX|
**** v1 CLI RX|Authentication required.
**** dT 0.171
**** v1 CLI TX|auth bf0ec06dd0f5b33f103201c2318f88e62dc16cf8f0cd3c8db846769398ba10be
*** v1 CLI RX 200
**** v1 CLI RX|-----------------------------
**** v1 CLI RX|Varnish Cache CLI 1.0
**** v1 CLI RX|-----------------------------
**** v1 CLI RX|Linux,4.18.0-553.44.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
**** v1 CLI RX|varnish-trunk revision 459a636f137c48328af64677ac426af5f4af7654
**** v1 CLI RX|
**** v1 CLI RX|Type 'help' for command list.
**** v1 CLI RX|Type 'quit' to close CLI session.
**** v1 CLI RX|Type 'start' to launch worker process.
**** v1 CLI TX|param.set feature +http2
**** dT 0.221
*** v1 CLI RX 200
** v1 CLI 200 <param.set feature +http2>
** top === varnish v1 -cliok "param.set debug +syncvsl"
**** v1 CLI TX|param.set debug +syncvsl
**** dT 0.273
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.276
*** v1 CLI RX 200
** v1 CLI 200 <param.set debug +syncvsl>
** top === varnish v1 -cliok "param.set h2_rapid_reset_limit 3"
**** v1 CLI TX|param.set h2_rapid_reset_limit 3
**** dT 0.329
*** v1 CLI RX 200
** v1 CLI 200 <param.set h2_rapid_reset_limit 3>
** top === varnish v1 -cliok "param.set h2_rapid_reset 5"
**** v1 CLI TX|param.set h2_rapid_reset 5
**** dT 0.376
*** v1 CLI RX 200
** v1 CLI 200 <param.set h2_rapid_reset 5>
** top === varnish v1 -vcl+backend {
**** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P
**** v1 CLI TX|vcl 4.1;
**** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "39379"; }
**** v1 CLI TX|
**** v1 CLI TX|
**** v1 CLI TX|\timport vtc;
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_recv {
**** v1 CLI TX|\t\tvtc.sleep(0.5s);
**** v1 CLI TX|\t\tif (req.http.barrier) {
**** v1 CLI TX|\t\t\tvtc.barrier_sync(req.http.barrier);
**** v1 CLI TX|\t\t}
**** v1 CLI TX|\t\tvtc.barrier_sync("127.0.0.1:37437");
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|
**** v1 CLI TX|%XJEIFLH|)Xspa8P
**** dT 0.377
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.481
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.583
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.686
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.789
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.893
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.924
*** v1 CLI RX 200
**** v1 CLI RX|VCL compiled.
**** v1 CLI TX|vcl.use vcl1
**** dT 0.926
*** v1 CLI RX 200
**** v1 CLI RX|VCL 'vcl1' now active
** v1 Start
**** v1 CLI TX|start
**** dT 0.981
*** v1 debug|Debug: Child (2092557) Started
**** dT 0.999
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 1.030
*** v1 debug|Child launched OK
**** dT 1.048
*** v1 CLI RX 200
*** v1 wait-running
**** v1 CLI TX|status
*** v1 debug|Info: Child (2092557) said Child starts
**** dT 1.052
*** v1 CLI RX 200
**** v1 CLI RX|Child in state running
**** v1 CLI TX|debug.listen_address
**** dT 1.102
**** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1742549632.991745/vgc.so 1auto
**** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1742549632.991745/vgc.so" as "vcl1"
**** v1 vsl| 0 CLI - Rd vcl.use "vcl1"
**** v1 vsl| 0 CLI - Wr 200 0
**** v1 vsl| 0 CLI - Rd start
**** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for a0=127.0.0.1:46081
**** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:46081
**** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:46081
**** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:46081
**** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:46081
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:46081
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:46081
**** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:46081
**** v1 vsl| 0 CLI - Wr 200 0
**** dT 1.156
*** v1 CLI RX 200
**** v1 CLI RX|a0 127.0.0.1 46081
**** v1 CLI TX|debug.xid 1000
**** dT 1.161
*** v1 CLI RX 200
**** v1 CLI RX|XID is 1000 chunk 1
**** v1 CLI TX|debug.listen_address
**** dT 1.206
**** v1 vsl| 0 CLI - Rd debug.listen_address
**** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 46081
**** v1 vsl| 0 CLI - Rd debug.xid 1000
**** v1 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1
**** dT 1.231
*** v1 CLI RX 200
**** v1 CLI RX|a0 127.0.0.1 46081
** v1 Listen on 127.0.0.1 46081
**** v1 macro def v1_addr=127.0.0.1
**** v1 macro def v1_port=46081
**** v1 macro def v1_sock=127.0.0.1:46081
**** v1 macro def v1_a0_addr=127.0.0.1
**** v1 macro def v1_a0_port=46081
**** v1 macro def v1_a0_sock=127.0.0.1:46081
** top === varnish v1 -vsl_catchup
**** dT 1.310
**** v1 vsl| 0 CLI - Rd debug.listen_address
**** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 46081
**** dT 1.335
** top === client c1 {
** c1 Starting client
** c1 Waiting for client
**** dT 1.336
** c1 Started on 127.0.0.1:46081 (1 iterations)
*** c1 Connect to 127.0.0.1:46081
*** c1 connected fd 19 from 127.0.0.1 35510 to 127.0.0.1:46081
** c1 === stream 0 {
**** c1 Not in H/2 mode, do what's needed
** c1 === txpri
**** c1 txpri|PRI * HTTP/2.0\r
**** c1 txpri|\r
**** c1 txpri|SM\r
**** c1 txpri|\r
**** dT 1.350
** c1 === stream 0 {
** c1 Starting stream 0 (0x3ff8c0015d0)
** c1 Waiting for stream 0
**** dT 1.355
** c1.0 === txsettings
*** c1.0 tx: stream: 0, type: SETTINGS (4), flags: 0x00, size: 0
** c1.0 === rxsettings
**** dT 1.368
*** c1 rx: stream: 0, type: SETTINGS (4), flags: 0x00, size: 18
**** c1.0 settings->MAX_CONCURRENT_STREAMS (3): 100
**** c1.0 settings->INITIAL_WINDOW_SIZE (4): 1048576
**** c1.0 settings->MAX_HEADER_LIST_SIZE (6): 32768
**** dT 1.371
** c1.0 === txsettings -ack
*** c1.0 tx: stream: 0, type: SETTINGS (4), flags: 0x01, size: 0
** c1.0 === rxsettings
**** dT 1.373
*** c1 rx: stream: 0, type: SETTINGS (4), flags: 0x01, size: 0
*** c1 flag: ACK
**** dT 1.376
** c1.0 === expect settings.ack == true
**** c1.0 EXPECT settings.ack (true) == "true" match
** c1.0 Ending stream 0
**** dT 1.377
** c1 Starting stream 0 (0x3ff8c0015d0)
** c1 === loop 4 {
**** c1 Loop #0
** c1 === stream next {
** c1 Starting stream 1 (0x3ff8c002df0)
** c1 Waiting for stream 1
**** dT 1.378
** c1.1 === txreq -hdr barrier 127.0.0.1:38283
*** c1.1 tx: stream: 1, type: HEADERS (1), flags: 0x05, size: 61
** c1.1 === barrier b1 sync
**** c1.1 Barrier(b1) sync with socket
** c1.0 === rxgoaway
**** dT 1.382
**** b1 Barrier(b1) wait 1 of 2
**** dT 1.410
**** v1 vsl| 1000 Begin c sess 0 HTTP/1
**** v1 vsl| 1000 SessOpen c 127.0.0.1 35510 a0 127.0.0.1 46081 1742549633.954325 22
**** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:46081
**** v1 vsl| 1000 Debug c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:46081
**** v1 vsl| 1000 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:46081
**** v1 vsl| 1000 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:46081
**** v1 vsl| 1000 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:46081
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:46081
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:46081
**** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:46081
**** v1 vsl| 1000 Debug c H2 Prior Knowledge Upgrade
**** v1 vsl| 1000 Debug c H2: Got pu PRISM
**** v1 vsl| 1000 H2RxHdr c [000000040000000000]
**** v1 vsl| 1000 Debug c H2RXF SETTINGS[0] 0x00 0x00000000
**** v1 vsl| 1000 H2RxHdr c [000000040100000000]
**** v1 vsl| 1000 Debug c H2RXF SETTINGS[0] 0x01 0x00000000
**** v1 vsl| 1000 H2RxHdr c [00003d010500000001]
**** v1 vsl| 1000 H2RxBody c [0007626172726965720f3132372e302e302e313a333832383300053a70617468012f00073a6d6574686f640347455400073a736368656d650468747470]
**** v1 vsl| 1000 Debug c H2RXF HEADERS[61] 0x05 0x00000001 0x0007626172726965720f3132372e302e302e313a333832383300053a70617468012f00073a6d6574686f640347455400073a736368656d650468747470
**** v1 vsl| 1001 Begin c req 1000 rxreq
**** v1 vsl| 1000 Link c req 1001 rxreq
**** v1 vsl| 1001 Timestamp c Start: 1742549633.985756 0.000000 0.000000
**** v1 vsl| 1001 ReqProtocol c HTTP/2.0
**** v1 vsl| 1001 Timestamp c Req: 1742549633.991405 0.005648 0.005648
**** v1 vsl| 1001 VCL_use c vcl1
**** v1 vsl| 1001 ReqStart c 127.0.0.1 35510 a0
**** v1 vsl| 1001 ReqMethod c GET
**** v1 vsl| 1001 ReqURL c /
**** v1 vsl| 1001 ReqProtocol c HTTP/2.0
**** v1 vsl| 1001 ReqHeader c barrier: 127.0.0.1:38283
**** v1 vsl| 1001 ReqHeader c scheme: http
**** v1 vsl| 1001 ReqHeader c X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1001 ReqHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1001 VCL_call c RECV
**** dT 1.882
**** b1 Barrier(b1) wake 2
**** dT 1.885
** c1.1 === txrst
*** c1.1 tx: stream: 1, type: RST_STREAM (3), flags: 0x00, size: 4
** c1.1 Ending stream 1
**** dT 1.887
**** b2 Barrier(b2) wait 1 of 5
**** c1 Loop #1
** c1 === stream next {
** c1 Starting stream 3 (0x3ff8c004540)
** c1 Waiting for stream 3
**** dT 1.924
**** v1 vsl| 1001 Debug c barrier_sync("127.0.0.1:38283")
**** v1 vsl| 1001 Debug c barrier_sync("127.0.0.1:37437")
**** v1 vsl| 1000 H2RxHdr c [000004030000000001]
**** v1 vsl| 1000 H2RxBody c [00000000]
**** v1 vsl| 1000 Debug c H2RXF RST_STREAM[4] 0x00 0x00000001 0x00000000
**** v1 vsl| 1000 Debug c KILL st=1 state=5 sched=1
**** dT 1.934
** c1.3 === txreq -hdr barrier 127.0.0.1:38283
*** c1.3 tx: stream: 3, type: HEADERS (1), flags: 0x05, size: 61
** c1.3 === barrier b1 sync
**** c1.3 Barrier(b1) sync with socket
**** dT 1.937
**** b1 Barrier(b1) wait 1 of 2
**** dT 2.026
**** v1 vsl| 1000 H2RxHdr c [00003d010500000003]
**** v1 vsl| 1000 H2RxBody c [0007626172726965720f3132372e302e302e313a333832383300053a70617468012f00073a6d6574686f640347455400073a736368656d650468747470]
**** v1 vsl| 1000 Debug c H2RXF HEADERS[61] 0x05 0x00000003 0x0007626172726965720f3132372e302e302e313a333832383300053a70617468012f00073a6d6574686f640347455400073a736368656d650468747470
**** v1 vsl| 1002 Begin c req 1000 rxreq
**** v1 vsl| 1000 Link c req 1002 rxreq
**** v1 vsl| 1002 Timestamp c Start: 1742549634.503164 0.000000 0.000000
**** v1 vsl| 1002 ReqProtocol c HTTP/2.0
**** v1 vsl| 1002 Timestamp c Req: 1742549634.550628 0.047463 0.047463
**** v1 vsl| 1002 VCL_use c vcl1
**** v1 vsl| 1002 ReqStart c 127.0.0.1 35510 a0
**** v1 vsl| 1002 ReqMethod c GET
**** v1 vsl| 1002 ReqURL c /
**** v1 vsl| 1002 ReqProtocol c HTTP/2.0
**** v1 vsl| 1002 ReqHeader c barrier: 127.0.0.1:38283
**** v1 vsl| 1002 ReqHeader c scheme: http
**** v1 vsl| 1002 ReqHeader c X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1002 ReqHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1002 VCL_call c RECV
**** dT 2.440
**** b1 Barrier(b1) wake 2
**** b2 Barrier(b2) wait 2 of 5
**** dT 2.543
**** v1 vsl| 1002 Debug c barrier_sync("127.0.0.1:38283")
**** v1 vsl| 1002 Debug c barrier_sync("127.0.0.1:37437")
**** dT 2.939
** c1.3 === txrst
*** c1.3 tx: stream: 3, type: RST_STREAM (3), flags: 0x00, size: 4
** c1.3 Ending stream 3
**** dT 2.940
**** c1 Loop #2
** c1 === stream next {
** c1 Starting stream 5 (0x3ff8c005c30)
** c1 Waiting for stream 5
** c1.5 === txreq -hdr barrier 127.0.0.1:38283
*** c1.5 tx: stream: 5, type: HEADERS (1), flags: 0x05, size: 61
** c1.5 === barrier b1 sync
**** c1.5 Barrier(b1) sync with socket
**** dT 2.945
**** b1 Barrier(b1) wait 1 of 2
**** dT 2.946
**** v1 vsl| 1000 H2RxHdr c [000004030000000003]
**** v1 vsl| 1000 H2RxBody c [00000000]
**** v1 vsl| 1000 Debug c H2RXF RST_STREAM[4] 0x00 0x00000003 0x00000000
**** v1 vsl| 1000 Debug c KILL st=3 state=5 sched=1
**** dT 3.150
**** v1 vsl| 1000 H2RxHdr c [00003d010500000005]
**** v1 vsl| 1000 H2RxBody c [0007626172726965720f3132372e302e302e313a333832383300053a70617468012f00073a6d6574686f640347455400073a736368656d650468747470]
**** v1 vsl| 1000 Debug c H2RXF HEADERS[61] 0x05 0x00000005 0x0007626172726965720f3132372e302e302e313a333832383300053a70617468012f00073a6d6574686f640347455400073a736368656d650468747470
**** v1 vsl| 1003 Begin c req 1000 rxreq
**** v1 vsl| 1000 Link c req 1003 rxreq
**** v1 vsl| 1003 Timestamp c Start: 1742549635.552194 0.000000 0.000000
**** v1 vsl| 1003 ReqProtocol c HTTP/2.0
**** v1 vsl| 1003 Timestamp c Req: 1742549635.762825 0.210630 0.210630
**** v1 vsl| 1003 VCL_use c vcl1
**** v1 vsl| 1003 ReqStart c 127.0.0.1 35510 a0
**** v1 vsl| 1003 ReqMethod c GET
**** v1 vsl| 1003 ReqURL c /
**** v1 vsl| 1003 ReqProtocol c HTTP/2.0
**** v1 vsl| 1003 ReqHeader c barrier: 127.0.0.1:38283
**** v1 vsl| 1003 ReqHeader c scheme: http
**** v1 vsl| 1003 ReqHeader c X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1003 ReqHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1003 VCL_call c RECV
**** dT 3.657
**** b1 Barrier(b1) wake 2
**** v1 vsl| 1003 Debug c barrier_sync("127.0.0.1:38283")
**** dT 3.658
** c1.5 === txrst
*** c1.5 tx: stream: 5, type: RST_STREAM (3), flags: 0x00, size: 4
** c1.5 Ending stream 5
**** dT 3.660
**** b2 Barrier(b2) wait 3 of 5
**** c1 Loop #3
** c1 === stream next {
** c1 Starting stream 7 (0x3ff8c007320)
** c1 Waiting for stream 7
** c1.7 === txreq -hdr barrier 127.0.0.1:38283
*** c1.7 tx: stream: 7, type: HEADERS (1), flags: 0x05, size: 61
** c1.7 === barrier b1 sync
**** c1.7 Barrier(b1) sync with socket
**** dT 3.661
**** b1 Barrier(b1) wait 1 of 2
**** dT 3.762
**** v1 vsl| 1003 Debug c barrier_sync("127.0.0.1:37437")
**** dT 4.173
**** v1 vsl| 1000 H2RxHdr c [000004030000000005]
**** v1 vsl| 1000 H2RxBody c [00000000]
**** v1 vsl| 1000 Debug c H2RXF RST_STREAM[4] 0x00 0x00000005 0x00000000
**** v1 vsl| 1000 Debug c KILL st=5 state=5 sched=1
**** v1 vsl| 1000 H2RxHdr c [00003d010500000007]
**** v1 vsl| 1000 H2RxBody c [0007626172726965720f3132372e302e302e313a333832383300053a70617468012f00073a6d6574686f640347455400073a736368656d650468747470]
**** v1 vsl| 1000 Debug c H2RXF HEADERS[61] 0x05 0x00000007 0x0007626172726965720f3132372e302e302e313a333832383300053a70617468012f00073a6d6574686f640347455400073a736368656d650468747470
**** v1 vsl| 1004 Begin c req 1000 rxreq
**** v1 vsl| 1000 Link c req 1004 rxreq
**** v1 vsl| 1004 Timestamp c Start: 1742549636.739973 0.000000 0.000000
**** v1 vsl| 1004 ReqProtocol c HTTP/2.0
**** v1 vsl| 1004 Timestamp c Req: 1742549636.740024 0.000051 0.000051
**** v1 vsl| 1004 VCL_use c vcl1
**** v1 vsl| 1004 ReqStart c 127.0.0.1 35510 a0
**** v1 vsl| 1004 ReqMethod c GET
**** v1 vsl| 1004 ReqURL c /
**** v1 vsl| 1004 ReqProtocol c HTTP/2.0
**** v1 vsl| 1004 ReqHeader c barrier: 127.0.0.1:38283
**** v1 vsl| 1004 ReqHeader c scheme: http
**** v1 vsl| 1004 ReqHeader c X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1004 ReqHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1004 VCL_call c RECV
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549636 1.0
**** dT 4.630
**** b1 Barrier(b1) wake 2
**** dT 4.631
** c1.7 === txrst
*** c1.7 tx: stream: 7, type: RST_STREAM (3), flags: 0x00, size: 4
** c1.7 Ending stream 7
**** dT 4.635
**** b2 Barrier(b2) wait 4 of 5
** c1 === barrier b2 sync
**** c1 Barrier(b2) sync with socket
**** b2 Barrier(b2) wake 5
** c1 === stream 0 -wait
** c1 Waiting for stream 0
**** dT 4.637
*** s1 accepted fd 8 127.0.0.1 58880
** s1 === rxreq
**** s1 rxhdr|GET / HTTP/1.1\r
**** s1 rxhdr|barrier: 127.0.0.1:38283\r
**** s1 rxhdr|scheme: http\r
**** s1 rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** s1 rxhdr|Accept-Encoding: gzip\r
**** s1 rxhdr|X-Varnish: 1005\r
**** s1 rxhdr|Host: 127.0.0.1\r
**** s1 rxhdr|\r
**** s1 rxhdrlen = 172
**** s1 http[ 0] |GET
**** s1 http[ 1] |/
**** s1 http[ 2] |HTTP/1.1
**** s1 http[ 3] |barrier: 127.0.0.1:38283
**** s1 http[ 4] |scheme: http
**** s1 http[ 5] |X-Forwarded-For: 127.0.0.1
**** s1 http[ 6] |Via: 1.1 v1 (Varnish/trunk)
**** s1 http[ 7] |Accept-Encoding: gzip
**** s1 http[ 8] |X-Varnish: 1005
**** s1 http[ 9] |Host: 127.0.0.1
**** s1 bodylen = 0
** s1 === txresp
**** s1 txresp|HTTP/1.1 200 OK\r
**** s1 txresp|Date: Fri, 21 Mar 2025 09:33:57 GMT\r
**** s1 txresp|Server: s1\r
**** s1 txresp|Content-Length: 0\r
**** s1 txresp|\r
*** s1 shutting fd 8
** s1 Ending
**** dT 4.648
*** c1 rx: stream: 7, type: HEADERS (1), flags: 0x05, size: 95
*** c1 flag: END_STREAM
**** c1 header[ 0]: :status: 200
**** c1 header[ 1]: date: Fri, 21 Mar 2025 09:33:57 GMT
**** c1 header[ 2]: server: s1
**** c1 header[ 3]: content-length: 0
**** c1 header[ 4]: x-varnish: 1004
**** c1 header[ 5]: age: 0
**** c1 header[ 6]: via: 1.1 v1 (Varnish/trunk)
**** c1 header[ 7]: accept-ranges: bytes
**** dT 4.686
**** v1 vsl| 1004 Debug c barrier_sync("127.0.0.1:38283")
**** v1 vsl| 1004 Debug c barrier_sync("127.0.0.1:37437")
**** v1 vsl| 1002 VCL_return c hash
**** v1 vsl| 1002 Timestamp c Reset: 1742549637.248613 2.745449 2.697985
**** v1 vsl| 1002 RespProtocol c HTTP/1.1
**** v1 vsl| 1002 RespStatus c 408
**** v1 vsl| 1002 RespReason c Client disconnected
**** v1 vsl| 1002 RespHeader c Date: Fri, 21 Mar 2025 09:33:57 GMT
**** v1 vsl| 1002 RespHeader c Server: Varnish
**** v1 vsl| 1002 RespHeader c X-Varnish: 1002
**** v1 vsl| 1002 Timestamp c Process: 1742549637.248699 2.745534 0.000085
**** v1 vsl| 1002 RespProtocol c HTTP/2.0
**** v1 vsl| 1002 RespStatus c 408
**** v1 vsl| 1002 RespReason c Request Timeout
**** v1 vsl| 1002 Timestamp c Resp: 1742549637.248708 2.745543 0.000009
**** v1 vsl| 1004 VCL_return c hash
**** v1 vsl| 1004 VCL_call c HASH
**** v1 vsl| 1004 VCL_return c lookup
**** v1 vsl| 1004 VCL_call c MISS
**** v1 vsl| 1004 VCL_return c fetch
**** v1 vsl| 1005 Begin b bereq 1004 fetch
**** v1 vsl| 1005 VCL_use b vcl1
**** v1 vsl| 1004 Link c bereq 1005 fetch
**** v1 vsl| 1005 Timestamp b Start: 1742549637.250054 0.000000 0.000000
**** v1 vsl| 1005 BereqMethod b GET
**** v1 vsl| 1005 BereqURL b /
**** v1 vsl| 1005 BereqProtocol b HTTP/2.0
**** v1 vsl| 1005 BereqHeader b barrier: 127.0.0.1:38283
**** v1 vsl| 1005 BereqHeader b scheme: http
**** v1 vsl| 1005 BereqHeader b X-Forwarded-For: 127.0.0.1
**** v1 vsl| 1005 BereqHeader b Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1005 BereqHeader b Accept-Encoding: gzip
**** v1 vsl| 1005 BereqProtocol b HTTP/1.1
**** v1 vsl| 1005 BereqHeader b X-Varnish: 1005
**** v1 vsl| 1005 VCL_call b BACKEND_FETCH
**** v1 vsl| 1005 VCL_return b fetch
**** v1 vsl| 1005 Timestamp b Fetch: 1742549637.250109 0.000055 0.000055
**** v1 vsl| 1005 BereqHeader b Host: 127.0.0.1
**** v1 vsl| 1005 Timestamp b Connected: 1742549637.250140 0.000086 0.000030
**** v1 vsl| 1005 BackendOpen b 26 s1 127.0.0.1 39379 127.0.0.1 58880 connect
**** v1 vsl| 1005 Timestamp b Bereq: 1742549637.250169 0.000115 0.000029
**** v1 vsl| 1005 BerespProtocol b HTTP/1.1
**** v1 vsl| 1005 BerespStatus b 200
**** v1 vsl| 1005 BerespReason b OK
**** v1 vsl| 1005 BerespHeader b Date: Fri, 21 Mar 2025 09:33:57 GMT
**** v1 vsl| 1005 BerespHeader b Server: s1
**** v1 vsl| 1005 BerespHeader b Content-Length: 0
**** v1 vsl| 1005 Timestamp b Beresp: 1742549637.250417 0.000363 0.000247
**** v1 vsl| 1005 TTL b RFC 120 10 0 1742549637 1742549637 1742549637 0 0 cacheable
**** v1 vsl| 1005 VCL_call b BACKEND_RESPONSE
**** v1 vsl| 1005 VCL_return b deliver
**** v1 vsl| 1005 Debug b Missing content-range header or unknown range unit
**** v1 vsl| 1005 Timestamp b Process: 1742549637.250442 0.000388 0.000024
**** v1 vsl| 1005 Filters b
**** v1 vsl| 1005 Storage b malloc s0
**** v1 vsl| 1005 Fetch_Body b 0 none -
**** v1 vsl| 1005 BackendClose b 26 s1 recycle
**** v1 vsl| 1003 VCL_return c hash
**** v1 vsl| 1003 Timestamp c Reset: 1742549637.250930 1.698735 1.488105
**** v1 vsl| 1003 RespProtocol c HTTP/1.1
**** v1 vsl| 1003 RespStatus c 408
**** v1 vsl| 1003 RespReason c Client disconnected
**** v1 vsl| 1003 RespHeader c Date: Fri, 21 Mar 2025 09:33:57 GMT
**** v1 vsl| 1003 RespHeader c Server: Varnish
**** v1 vsl| 1003 RespHeader c X-Varnish: 1003
**** v1 vsl| 1003 Timestamp c Process: 1742549637.250939 1.698745 0.000009
**** v1 vsl| 1003 RespProtocol c HTTP/2.0
**** v1 vsl| 1003 RespStatus c 408
**** v1 vsl| 1003 RespReason c Request Timeout
**** v1 vsl| 1003 Timestamp c Resp: 1742549637.250943 1.698748 0.000003
**** v1 vsl| 1001 VCL_return c hash
**** v1 vsl| 1001 Timestamp c Reset: 1742549637.254618 3.268861 3.263212
**** v1 vsl| 1001 RespProtocol c HTTP/1.1
**** v1 vsl| 1001 RespStatus c 408
**** v1 vsl| 1001 RespReason c Client disconnected
**** v1 vsl| 1001 RespHeader c Date: Fri, 21 Mar 2025 09:33:57 GMT
**** v1 vsl| 1001 RespHeader c Server: Varnish
**** v1 vsl| 1001 RespHeader c X-Varnish: 1001
**** v1 vsl| 1001 Timestamp c Process: 1742549637.254634 3.268877 0.000015
**** v1 vsl| 1001 RespProtocol c HTTP/2.0
**** v1 vsl| 1001 RespStatus c 408
**** v1 vsl| 1001 RespReason c Request Timeout
**** v1 vsl| 1001 Timestamp c Resp: 1742549637.254638 3.268881 0.000004
**** v1 vsl| 1005 Timestamp b BerespBody: 1742549637.261122 0.011067 0.010679
**** v1 vsl| 1005 Length b 0
**** v1 vsl| 1005 BereqAcct b 172 0 172 87 0 87
**** v1 vsl| 1005 End b
**** v1 vsl| 1004 Timestamp c Fetch: 1742549637.261267 0.521294 0.521242
**** v1 vsl| 1004 RespProtocol c HTTP/1.1
**** v1 vsl| 1004 RespStatus c 200
**** v1 vsl| 1004 RespReason c OK
**** v1 vsl| 1004 RespHeader c Date: Fri, 21 Mar 2025 09:33:57 GMT
**** v1 vsl| 1004 RespHeader c Server: s1
**** v1 vsl| 1004 RespHeader c Content-Length: 0
**** v1 vsl| 1004 RespHeader c X-Varnish: 1004
**** v1 vsl| 1004 RespHeader c Age: 0
**** v1 vsl| 1004 RespHeader c Via: 1.1 v1 (Varnish/trunk)
**** v1 vsl| 1004 RespHeader c Accept-Ranges: bytes
**** v1 vsl| 1004 VCL_call c DELIVER
**** v1 vsl| 1004 VCL_return c deliver
**** v1 vsl| 1004 Timestamp c Process: 1742549637.261292 0.521319 0.000025
**** v1 vsl| 1004 Filters c
**** v1 vsl| 1004 RespProtocol c HTTP/2.0
**** v1 vsl| 1004 Debug c HP {33, "date:", ""} <Date: Fri, 21 Mar 2025 09:33:57 GMT>
**** v1 vsl| 1004 Debug c HP {54, "server:", ""} <Server: s1>
**** v1 vsl| 1004 Debug c HP {28, "content-length:", ""} <Content-Length: 0>
**** v1 vsl| 1004 Debug c HP {21, "age:", ""} <Age: 0>
**** v1 vsl| 1004 Debug c HP {60, "via:", ""} <Via: 1.1 v1 (Varnish/trunk)>
**** v1 vsl| 1004 Debug c HP {18, "accept-ranges:", ""} <Accept-Ranges: bytes>
**** v1 vsl| 1004 Timestamp c Resp: 1742549637.261322 0.521349 0.000030
**** v1 vsl| 1001 ReqAcct c 61 0 61 0 0 0
**** v1 vsl| 1001 End c
**** v1 vsl| 1002 ReqAcct c 61 0 61 0 0 0
**** v1 vsl| 1002 End c
**** v1 vsl| 1003 ReqAcct c 61 0 61 0 0 0
**** v1 vsl| 1003 End c
**** v1 vsl| 1004 ReqAcct c 61 0 61 95 0 95
**** v1 vsl| 1004 End c
**** v1 vsl| 1000 H2RxHdr c [000004030000000007]
**** v1 vsl| 1000 H2RxBody c [00000000]
**** v1 vsl| 1000 Debug c H2RXF RST_STREAM[4] 0x00 0x00000007 0x00000000
**** dT 7.230
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549639 1.0
**** dT 9.938
*** c1 rx: stream: 0, type: GOAWAY (7), flags: 0x00, size: 8
*** c1.0 goaway->laststream: 7
*** c1.0 goaway->err: NO_ERROR (0)
**** dT 9.939
** c1.0 === expect goaway.err == ENHANCE_YOUR_CALM
---- c1.0 EXPECT goaway.err (0) == "11" failed
**** dT 9.992
**** v1 vsl| 1000 Debug c H2 CLEANUP H2CE_NO_ERROR
**** v1 vsl| 1000 ReqAcct c 90 16 106 36 26 62
**** v1 vsl| 1000 SessClose c REM_CLOSE 8.597
**** v1 vsl| 1000 End c
**** dT 10.031
**** b2 macro undef b2_addr
**** b2 macro undef b2_port
**** b2 macro undef b2_sock
**** b1 macro undef b1_addr
**** b1 macro undef b1_port
**** b1 macro undef b1_sock
**** dT 10.193
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549642 1.0
**** dT 13.145
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549645 1.0
**** dT 16.187
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549648 1.0
**** dT 19.139
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549651 1.0
**** dT 22.218
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549654 1.0
**** dT 25.174
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549657 1.0
**** dT 28.238
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549660 1.0
**** dT 31.214
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549663 1.0
**** dT 34.165
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549666 1.0
**** dT 37.218
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549669 1.0
**** dT 40.177
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549672 1.0
**** dT 43.234
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549675 1.0
**** dT 46.184
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549678 1.0
**** dT 49.251
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549681 1.0
**** dT 52.214
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549684 1.0
**** dT 55.173
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549687 1.0
**** dT 58.216
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549690 1.0
**** dT 61.209
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549693 1.0
**** dT 64.269
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549696 1.0
**** dT 67.230
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549699 1.0
**** dT 70.286
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549702 1.0
**** dT 73.240
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549705 1.0
**** dT 76.204
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549708 1.0
**** dT 79.269
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549711 1.0
**** dT 82.308
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549714 1.0
**** dT 85.245
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549717 1.0
**** dT 88.307
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549720 1.0
**** dT 91.264
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549723 1.0
**** dT 94.320
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549726 1.0
**** dT 97.291
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549729 1.0
**** dT 100.331
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549732 1.0
**** dT 103.285
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549735 1.0
**** dT 106.336
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549738 1.0
**** dT 109.288
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549741 1.0
**** dT 112.335
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549744 1.0
**** dT 115.299
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549747 1.0
**** dT 118.364
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1742549750 1.0
# top TEST ../../../../bin/varnishtest/tests/r03996.vtc TIMED OUT (kill -9)
# top TEST ../../../../bin/varnishtest/tests/r03996.vtc FAILED (120.108) signal=9
FAIL tests/r03996.vtc (exit status: 2)